AWS JDBC Driver の Failover Plugin を使って3秒でAurora DB ClusterのWriterをフェイルオーバーしてみた

AWS JDBC Driverを使うときは複数のプラグインを使いこなしたい

#Amazon Aurora

#AWS

#RDS Proxy

のんピ

2023.06.26

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

Amazon Auroraのフェイルオーバー時間を短くしたい

こんにちは、のんピ(@non____97)です。

皆さんはAmazon Auroraのフェイルオーバー時間を短くしたいなと思ったことはありますか? 私はあります。

Auroraのフェイルオーバー時間は60秒未満と言われています。しかし、「60秒では長すぎる。せめて10秒程度でフェイルオーバーは完了させたい。」といったこともあると思います。

フェイルオーバー時間を短くする方法はクライアント側でMariaDB Connector/JやPostgreSQL JDBC Driverなどのドライバーを使用したり、RDS ProxyやProxySQLなどプロキシを挟むパターンがあります。

他にもフェイルオーバー時間を短くする方法が何かないかと探しているとAWS公式ドキュメントにフェイルオーバー時間を短くするための方法がまとまっていました。

その中にAWS JDBC Driverなるドライバーが紹介されていました。

DevelopersIOではこちらのドライバーを使ってフェイルオーバー時間の短縮する方法を説明している記事がなかったので、検証をしてみます。

いきなりまとめ

AWS JDBC Driver(aws-advanced-jdbc-wrapper)とはAWS謹製のJDBC Wrapper
機能ごとに様々なプラグインが存在 (以下例)
- Failover Connection Plugin : フェイルオーバーの高速化
- AWS Secrets Manager Connection Plugin : Secrets Managerから認証情報を取得
- Read-Write Splitting Plugin : 読み取り/書き込みに応じてWriter/Readerインスタンスを切り替え
Failover Connection Pluginを使う場合、例外が発生した際にConnectionオブジェクトを破棄しないようにする必要がある
- フェイルオーバー成功時の例外FailoverSuccessSQLExceptionの場合は、Connectionオブジェクトを再利用してリトライしてあげる
strict-writerの場合、DBインスタンスの数が3台以上だと15秒未満でフェイルオーバーできる
- 検証した限りDBインスタンス4台で2-5秒ほどでフェイルオーバー
reader-or-writerの場合、DBインスタンスの数が2台でも0.4秒ほどでフェイルオーバーできる
以下に当てはまる場合は積極的に活用していきたい
- RDS ProxyやDBのプロキシのミドルウェア用のEC2インスタンス料金を抑えたい
- アプリケーションの改修が可能
- DBクラスターを3台以上で構成

AWS JDBC Driverとは

AWS JDBC Driver(aws-advanced-jdbc-wrapper)とはAWS謹製のJDBC Wrapperです。

AWS JDBC Driverにはフェイルオーバーを高速化するFailover Connection Plugin以外にもSecrets Managerから認証情報を取得するAWS Secrets Manager Connection Plugin、読み取り/書き込みに応じてWriter/Readerインスタンスを切り替えるRead-Write Splitting Pluginなどもあります。

Plugin name	Plugin Code	Database Compatibility	Description
Failover Connection Plugin	failover	Aurora	Enables the failover functionality supported by Amazon Aurora clusters. Prevents opening a wrong connection to an old writer node dues to stale DNS after failover event. This plugin is enabled by default.
Host Monitoring Connection Plugin	efm	Aurora	Enables enhanced host connection failure monitoring, allowing faster failure detection rates. This plugin is enabled by default.
Aurora Host List Connection Plugin	auroraHostList	Aurora	Retrieves Amazon Aurora clusters information. ⚠️Note: this plugin does not need to be explicitly loaded if the failover connection plugin is loaded.
Data Cache Connection Plugin	dataCache	Any database	Caches results from SQL queries matching the regular expression specified in the dataCacheTriggerCondition configuration parameter.
Execution Time Connection Plugin	executionTime	Any database	Logs the time taken to execute any JDBC method.
Log Query Connection Plugin	logQuery	Any database	Tracks and logs the SQL statements to be executed. Sometimes SQL statements are not passed directly to the JDBC method as a parameter, such as executeBatch(). Users can set enhancedLogQueryEnabled to true, allowing the JDBC Wrapper to obtain SQL statements via Java Reflection. ⚠️Note: Enabling Java Reflection may cause a performance degradation.
IAM Authentication Connection Plugin	iam	Any database	Enables users to connect to their Amazon Aurora clusters using AWS Identity and Access Management (IAM).
AWS Secrets Manager Connection Plugin	awsSecretsManager	Any database	Enables fetching database credentials from the AWS Secrets Manager service.
Aurora Stale DNS Plugin	auroraStaleDns	Aurora	Prevents incorrectly opening a new connection to an old writer node when DNS records have not yet updated after a recent failover event. ⚠️Note: Contrary to failover plugin, auroraStaleDns plugin doesn't implement failover support itself. It helps to eliminate opening wrong connections to an old writer node after cluster failover is completed. ⚠️Note: This logic is already included in failover plugin so you can omit using both plugins at the same time.
Aurora Connection Tracker Plugin	auroraConnectionTracker	Aurora	Tracks all the opened connections. In the event of a cluster failover, the plugin will close all the impacted connections to the node. This plugin is enabled by default.
Driver Metadata Connection Plugin	driverMetaData	Any database	Allows user application to override the return value of DatabaseMetaData#getDriverName
Read Write Splitting Plugin	readWriteSplitting	Aurora	Enables read write splitting functionality where users can switch between database reader and writer instances.

抜粋 : aws-advanced-jdbc-wrapper/docs/using-the-jdbc-driver/UsingTheJdbcDriver.md at main · awslabs/aws-advanced-jdbc-wrapper

AWS JDBC DriverでFailover Connection Pluginを使用している環境でフェイルオーバーが発生した場合の内部挙動は以下の通りです。

failover_diagram

Failover Connection Pluginを使用するとDBへの物理接続と論理接続が分離されます。そして物理接続先のDBインスタンスに異常が見られる場合以下のステップで物理接続の切り替えが行われます。

内部のトポロジキャッシュからアクティブなAuroraレプリカに接続
接続したAuroraレプリカからWriterの情報を取得
Writerの特定が完了したら、物理接続先を切り替え

Failover Connection Pluginの挙動はエムスリーさんのテックブログでも解説されており、非常に参考になります。

検証環境の準備

検証環境は以下の通りです。

AWS JDBC Driver の Failover Plugin を使って3秒でWriterをフェイルオーバーしてみた検証環境構成図

EC2インスタンスでSpring Bootを起動させ、Aurora DBクラスターに接続させます。

各DBインスタンスのIPアドレスは以下の通りです。

$ dig db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com +short
10.1.1.93

$ dig db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com +short
10.1.1.116

各種AWSリソースはAWS CDKでデプロイします。デプロイ時に使用したリポジトリは本記事の終わりに記載しています。

EC2インスタンス起動後、Spring Bootのアプリケーションを作成します。

まずJavaのインストールをします。

$ sudo dnf install java
Last metadata expiration check: 0:02:23 ago on Wed Jun 21 05:06:39 2023.
Dependencies resolved.
========================================================================================================================
 Package                                   Architecture    Version                           Repository            Size
========================================================================================================================
Installing:
 java-17-amazon-corretto                   x86_64          1:17.0.7+7-1.amzn2023.1           amazonlinux          188 k
Installing dependencies:
 alsa-lib                                  x86_64          1.2.7.2-1.amzn2023.0.2            amazonlinux          504 k
 cairo                                     x86_64          1.17.4-3.amzn2023.0.2             amazonlinux          674 k
 dejavu-sans-fonts                         noarch          2.37-16.amzn2023.0.2              amazonlinux          1.3 M
 dejavu-sans-mono-fonts                    noarch          2.37-16.amzn2023.0.2              amazonlinux          467 k
 dejavu-serif-fonts                        noarch          2.37-16.amzn2023.0.2              amazonlinux          1.0 M
 fontconfig                                x86_64          2.13.94-2.amzn2023.0.2            amazonlinux          273 k
 fonts-filesystem                          noarch          1:2.0.5-5.amzn2023.0.2            amazonlinux          8.7 k
 freetype                                  x86_64          2.13.0-2.amzn2023.0.1             amazonlinux          422 k
 giflib                                    x86_64          5.2.1-9.amzn2023                  amazonlinux           49 k
 google-noto-fonts-common                  noarch          20201206-2.amzn2023.0.2           amazonlinux           15 k
 google-noto-sans-vf-fonts                 noarch          20201206-2.amzn2023.0.2           amazonlinux          492 k
 graphite2                                 x86_64          1.3.14-7.amzn2023.0.2             amazonlinux           97 k
 harfbuzz                                  x86_64          7.0.0-2.amzn2023.0.1              amazonlinux          868 k
 java-17-amazon-corretto-headless          x86_64          1:17.0.7+7-1.amzn2023.1           amazonlinux           91 M
 javapackages-filesystem                   noarch          6.0.0-7.amzn2023.0.5              amazonlinux           13 k
 langpacks-core-font-en                    noarch          3.0-21.amzn2023.0.4               amazonlinux           10 k
 libICE                                    x86_64          1.0.10-6.amzn2023.0.2             amazonlinux           71 k
 libSM                                     x86_64          1.2.3-8.amzn2023.0.2              amazonlinux           42 k
 libX11                                    x86_64          1.7.2-3.amzn2023.0.2              amazonlinux          657 k
 libX11-common                             noarch          1.7.2-3.amzn2023.0.2              amazonlinux          152 k
 libXau                                    x86_64          1.0.9-6.amzn2023.0.2              amazonlinux           31 k
 libXext                                   x86_64          1.3.4-6.amzn2023.0.2              amazonlinux           41 k
 libXi                                     x86_64          1.7.10-6.amzn2023.0.2             amazonlinux           40 k
 libXinerama                               x86_64          1.1.4-8.amzn2023.0.2              amazonlinux           15 k
 libXrandr                                 x86_64          1.5.2-6.amzn2023.0.2              amazonlinux           28 k
 libXrender                                x86_64          0.9.10-14.amzn2023.0.2            amazonlinux           28 k
 libXt                                     x86_64          1.2.0-4.amzn2023.0.2              amazonlinux          181 k
 libXtst                                   x86_64          1.2.3-14.amzn2023.0.2             amazonlinux           21 k
 libbrotli                                 x86_64          1.0.9-4.amzn2023.0.2              amazonlinux          315 k
 libjpeg-turbo                             x86_64          2.1.4-2.amzn2023.0.2              amazonlinux          190 k
 libpng                                    x86_64          2:1.6.37-10.amzn2023.0.2          amazonlinux          128 k
 libxcb                                    x86_64          1.13.1-7.amzn2023.0.2             amazonlinux          230 k
 pixman                                    x86_64          0.40.0-3.amzn2023.0.3             amazonlinux          295 k
 xml-common                                noarch          0.6.3-56.amzn2023.0.2             amazonlinux           32 k

Transaction Summary
========================================================================================================================
Install  35 Packages

Total download size: 100 M
Installed size: 261 M
Is this ok [y/N]: y
Downloading Packages:
(1/35): libXrender-0.9.10-14.amzn2023.0.2.x86_64.rpm                                    239 kB/s |  28 kB     00:00
(2/35): harfbuzz-7.0.0-2.amzn2023.0.1.x86_64.rpm                                        6.3 MB/s | 868 kB     00:00
.
.
(中略)
.
.
  Verifying        : langpacks-core-font-en-3.0-21.amzn2023.0.4.noarch                                            35/35

Installed:
  alsa-lib-1.2.7.2-1.amzn2023.0.2.x86_64
  cairo-1.17.4-3.amzn2023.0.2.x86_64
  dejavu-sans-fonts-2.37-16.amzn2023.0.2.noarch
.
.
(中略)
.
.
  libxcb-1.13.1-7.amzn2023.0.2.x86_64
  pixman-0.40.0-3.amzn2023.0.3.x86_64
  xml-common-0.6.3-56.amzn2023.0.2.noarch

Complete!

$ java --version
openjdk 17.0.7 2023-04-18 LTS
OpenJDK Runtime Environment Corretto-17.0.7.7.1 (build 17.0.7+7-LTS)
OpenJDK 64-Bit Server VM Corretto-17.0.7.7.1 (build 17.0.7+7-LTS, mixed mode, sharing)

続いて、Spring BootのビルドのためにMavenのインストールをします。

$ sudo dnf install maven
Last metadata expiration check: 0:19:31 ago on Wed Jun 21 05:06:39 2023.
Dependencies resolved.
========================================================================================================================
 Package                                        Architecture  Version                          Repository          Size
========================================================================================================================
Installing:
 maven                                          noarch        1:3.8.4-3.amzn2023.0.4           amazonlinux         18 k
Installing dependencies:
 apache-commons-cli                             noarch        1.5.0-3.amzn2023.0.3             amazonlinux         76 k
 apache-commons-codec                           noarch        1.15-6.amzn2023.0.3              amazonlinux        303 k
 apache-commons-io                              noarch        1:2.8.0-7.amzn2023.0.4           amazonlinux        284 k
 apache-commons-lang3                           noarch        3.12.0-7.amzn2023.0.3            amazonlinux        559 k
 atinject                                       noarch        1.0.5-3.amzn2023.0.3             amazonlinux         23 k
 cdi-api                                        noarch        2.0.2-6.amzn2023.0.3             amazonlinux         54 k
 google-guice                                   noarch        4.2.3-8.amzn2023.0.6             amazonlinux        473 k
 guava                                          noarch        31.0.1-3.amzn2023.0.4            amazonlinux        2.5 M
 httpcomponents-client                          noarch        4.5.13-4.amzn2023.0.4            amazonlinux        657 k
 httpcomponents-core                            noarch        4.4.13-6.amzn2023.0.3            amazonlinux        632 k
 jakarta-annotations                            noarch        1.3.5-13.amzn2023.0.3            amazonlinux         46 k
 jansi                                          x86_64        2.4.0-3.amzn2023.0.3             amazonlinux        113 k
 java-17-amazon-corretto-devel                  x86_64        1:17.0.7+7-1.amzn2023.1          amazonlinux        149 k
 jcl-over-slf4j                                 noarch        1.7.32-3.amzn2023.0.4            amazonlinux         25 k
 jsoup                                          noarch        1.13.1-9.amzn2023.0.4            amazonlinux        377 k
 jsr-305                                        noarch        3.0.2-5.amzn2023.0.4             amazonlinux         32 k
 maven-amazon-corretto17                        noarch        1:3.8.4-3.amzn2023.0.4           amazonlinux        9.7 k
 maven-lib                                      noarch        1:3.8.4-3.amzn2023.0.4           amazonlinux        1.5 M
 maven-resolver                                 noarch        1:1.7.3-3.amzn2023.0.4           amazonlinux        557 k
 maven-shared-utils                             noarch        3.3.4-4.amzn2023.0.3             amazonlinux        152 k
 maven-wagon                                    noarch        3.4.2-6.amzn2023.0.4             amazonlinux        113 k
 plexus-cipher                                  noarch        1.8-3.amzn2023.0.3               amazonlinux         27 k
 plexus-classworlds                             noarch        2.6.0-10.amzn2023.0.4            amazonlinux         61 k
 plexus-containers-component-annotations        noarch        2.1.0-9.amzn2023.0.4             amazonlinux         19 k
 plexus-interpolation                           noarch        1.26-10.amzn2023.0.4             amazonlinux         80 k
 plexus-sec-dispatcher                          noarch        2.0-3.amzn2023.0.3               amazonlinux         34 k
 plexus-utils                                   noarch        3.3.0-9.amzn2023.0.4             amazonlinux        254 k
 publicsuffix-list                              noarch        20221208-60.amzn2023             amazonlinux         87 k
 sisu                                           noarch        1:0.3.4-9.amzn2023.0.4           amazonlinux        510 k
 slf4j                                          noarch        1.7.32-3.amzn2023.0.4            amazonlinux         70 k

Transaction Summary
========================================================================================================================
Install  31 Packages

Total download size: 9.6 M
Installed size: 13 M
Is this ok [y/N]: y
Downloading Packages:
(1/31): java-17-amazon-corretto-devel-17.0.7+7-1.amzn2023.1.x86_64.rpm                  1.2 MB/s | 149 kB     00:00
(2/31): jsoup-1.13.1-9.amzn2023.0.4.noarch.rpm                                          2.7 MB/s | 377 kB     00:00
.
.
(中略)
.
.
  Verifying        : httpcomponents-core-4.4.13-6.amzn2023.0.3.noarch                                             30/31
  Verifying        : publicsuffix-list-20221208-60.amzn2023.noarch                                                31/31

Installed:
  apache-commons-cli-1.5.0-3.amzn2023.0.3.noarch
  apache-commons-codec-1.15-6.amzn2023.0.3.noarch
  apache-commons-io-1:2.8.0-7.amzn2023.0.4.noarch
.
.
(中略)
.
.
  publicsuffix-list-20221208-60.amzn2023.noarch
  sisu-1:0.3.4-9.amzn2023.0.4.noarch
  slf4j-1.7.32-3.amzn2023.0.4.noarch

Complete!

Spring Boot CLIをインストールします。

# Spring Boot CLIのダウンロード
$ wget https://repo.maven.apache.org/maven2/org/springframework/boot/spring-boot-cli/3.1.0/spring-boot-cli-3.1.0-bin.tar.gz
--2023-06-21 05:42:39--  https://repo.maven.apache.org/maven2/org/springframework/boot/spring-boot-cli/3.1.0/spring-boot-cli-3.1.0-bin.tar.gz
Resolving repo.maven.apache.org (repo.maven.apache.org)... 146.75.32.215, 2a04:4e42:78::215
Connecting to repo.maven.apache.org (repo.maven.apache.org)|146.75.32.215|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 5141514 (4.9M) [application/x-gzip]
Saving to: ‘spring-boot-cli-3.1.0-bin.tar.gz’

spring-boot-cli-3.1.0-bin.tar 100%[=================================================>]   4.90M  --.-KB/s    in 0.05s

2023-06-21 05:42:39 (104 MB/s) - ‘spring-boot-cli-3.1.0-bin.tar.gz’ saved [5141514/5141514]

# ダウンロードしたzipファイルを展開
$ tar zxvf spring-boot-cli-3.1.0-bin.tar.gz
spring-3.1.0/
spring-3.1.0/lib/
spring-3.1.0/lib/spring-boot-cli-3.1.0.jar
spring-3.1.0/shell-completion/
spring-3.1.0/shell-completion/bash/
spring-3.1.0/shell-completion/bash/spring
spring-3.1.0/shell-completion/zsh/
spring-3.1.0/shell-completion/zsh/_spring
spring-3.1.0/legal/
spring-3.1.0/legal/open_source_licenses.txt
spring-3.1.0/bin/
spring-3.1.0/bin/spring.bat
spring-3.1.0/LICENCE.txt
spring-3.1.0/INSTALL.txt
spring-3.1.0/bin/spring

# 展開されたファイルたちの確認
$ ls -lR spring-3.1.0/
spring-3.1.0/:
total 8
-rw-r--r--. 1 ec2-user ec2-user 1425 May 18 22:18 INSTALL.txt
-rw-r--r--. 1 ec2-user ec2-user  582 May 18 22:18 LICENCE.txt
drwxr-xr-x. 2 ec2-user ec2-user   38 Jun 21 05:43 bin
drwxr-xr-x. 2 ec2-user ec2-user   38 May 18 22:18 legal
drwxr-xr-x. 2 ec2-user ec2-user   39 May 18 22:21 lib
drwxr-xr-x. 4 ec2-user ec2-user   29 May 18 22:18 shell-completion

spring-3.1.0/bin:
total 8
-rwxr-xr-x. 1 ec2-user ec2-user 3367 May 18 22:18 spring
-rw-r--r--. 1 ec2-user ec2-user 1948 May 18 22:18 spring.bat

spring-3.1.0/legal:
total 12
-rw-r--r--. 1 ec2-user ec2-user 11103 May 18 22:18 open_source_licenses.txt

spring-3.1.0/lib:
total 5812
-rw-r--r--. 1 ec2-user ec2-user 5949256 May 18 22:21 spring-boot-cli-3.1.0.jar

spring-3.1.0/shell-completion:
total 0
drwxr-xr-x. 2 ec2-user ec2-user 20 May 18 22:18 bash
drwxr-xr-x. 2 ec2-user ec2-user 21 May 18 22:18 zsh

spring-3.1.0/shell-completion/bash:
total 4
-rw-r--r--. 1 ec2-user ec2-user 494 May 18 22:18 spring

spring-3.1.0/shell-completion/zsh:
total 4
-rw-r--r--. 1 ec2-user ec2-user 454 May 18 22:18 _spring

# spring コマンドが叩けられるように環境変数を設定
$ sudo vim /etc/profile
$ tail /etc/profile
        if [ -f /etc/bashrc ] ; then
                # Bash login shells run only /etc/profile
                # Bash non-login shells run only /etc/bashrc
                # Check for double sourcing is done in /etc/bashrc.
                . /etc/bashrc
       fi
fi

export SPRING_HOME=/home/ec2-user/spring-3.1.0/
export PATH=$SPRING_HOME/bin:$PATH

# 環境変数の再読み込み
$ source /etc/profile

# spring コマンドが叩けることを確認
$ which spring
~/spring-3.1.0/bin/spring

Spring Boot CLIから、Spring Initializr でプロジェクトの作成をします。

$ spring init \
  -g=net.non-97.aurora \
  -a=jdbc \
  -n=jdbc \
  -d=web,postgresql \
  -j=17 \
  -l=java \
  --package-name jar \
  --build=maven
Using service at https://start.spring.io
Content saved to 'jdbc.zip'

$ unzip jdbc.zip
Archive:  jdbc.zip
   creating: src/
   creating: src/main/
   creating: src/main/java/
   creating: src/main/java/jar/
  inflating: src/main/java/jar/JdbcApplication.java
   creating: src/main/resources/
  inflating: src/main/resources/application.properties
   creating: src/test/
   creating: src/test/java/
   creating: src/test/java/jar/
  inflating: src/test/java/jar/JdbcApplicationTests.java
  inflating: HELP.md
  inflating: .gitignore
  inflating: mvnw
  inflating: pom.xml
  inflating: mvnw.cmd
   creating: .mvn/
   creating: .mvn/wrapper/
  inflating: .mvn/wrapper/maven-wrapper.properties
  inflating: .mvn/wrapper/maven-wrapper.jar

# 展開された pom.xml の確認
$ cat pom.xml
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
        <modelVersion>4.0.0</modelVersion>
        <parent>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-starter-parent</artifactId>
                <version>3.1.0</version>
                <relativePath/> <!-- lookup parent from repository -->
        </parent>
        <groupId>net.non-97.aurora</groupId>
        <artifactId>jdbc</artifactId>
        <version>0.0.1-SNAPSHOT</version>
        <name>jdbc</name>
        <description>Demo project for Spring Boot</description>
        <properties>
                <java.version>17</java.version>
        </properties>
        <dependencies>
                <dependency>
                        <groupId>org.springframework.boot</groupId>
                        <artifactId>spring-boot-starter-web</artifactId>
                </dependency>

                <dependency>
                        <groupId>org.postgresql</groupId>
                        <artifactId>postgresql</artifactId>
                        <scope>runtime</scope>
                </dependency>
                <dependency>
                        <groupId>org.springframework.boot</groupId>
                        <artifactId>spring-boot-starter-test</artifactId>
                        <scope>test</scope>
                </dependency>
        </dependencies>

        <build>
                <plugins>
                        <plugin>
                                <groupId>org.springframework.boot</groupId>
                                <artifactId>spring-boot-maven-plugin</artifactId>
                        </plugin>
                </plugins>
        </build>

</project>

動作確認のために/helloにアクセスするとHello World!を返すようなJavaアプリケーションに修正してみます。

$ vi src/main/java/jar/JdbcApplication.java

$ cat src/main/java/jar/JdbcApplication.java
package jar;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
@RestController
public class JdbcApplication {

        public static void main(String[] args) {
                SpringApplication.run(JdbcApplication.class, args);
        }

        @GetMapping("/hello")
        String Hello(){
                return "Hello World!";
        }
}

修正後、Spring Bootを起動します。

$ mvn spring-boot:run
.
.
(中略)
.
.
[INFO] --- maven-resources-plugin:3.3.1:resources (default-resources) @ jdbc ---
[INFO] Copying 1 resource from src/main/resources to target/classes
[INFO] Copying 0 resource from src/main/resources to target/classes
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:compile (default-compile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :source
[INFO] Compiling 1 source file with javac [debug release 17] to target/classes
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:testResources (default-testResources) @ jdbc ---
[INFO] skip non existing resourceDirectory /home/ec2-user/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:testCompile (default-testCompile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :dependency
[INFO] Compiling 1 source file with javac [debug release 17] to target/test-classes
[INFO]
[INFO] <<< spring-boot-maven-plugin:3.1.0:run (default-cli) < test-compile @ jdbc <<<
[INFO]
[INFO]
[INFO] --- spring-boot-maven-plugin:3.1.0:run (default-cli) @ jdbc ---
[INFO] Attaching agents: []

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.1.0)

2023-06-21T07:23:09.968Z  INFO 30857 --- [           main] jar.JdbcApplication                      : Starting JdbcApplication using Java 17.0.7 with PID 30857 (/home/ec2-user/target/classes started by ec2-user in /home/ec2-user)
2023-06-21T07:23:09.972Z  INFO 30857 --- [           main] jar.JdbcApplication                      : No active profileset, falling back to 1 default profile: "default"
2023-06-21T07:23:10.864Z  INFO 30857 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2023-06-21T07:23:10.874Z  INFO 30857 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2023-06-21T07:23:10.874Z  INFO 30857 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.8]
2023-06-21T07:23:10.983Z  INFO 30857 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2023-06-21T07:23:10.985Z  INFO 30857 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 937 ms
2023-06-21T07:23:11.271Z  INFO 30857 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started onport(s): 8080 (http) with context path ''
2023-06-21T07:23:11.281Z  INFO 30857 --- [           main] jar.JdbcApplication                      : Started JdbcApplication in 1.66 seconds (process running for 2.037)

localhost:8080/helloにアクセスしてHello World!が返ってくることを確認します。

$ curl http://localhost:8080/hello
Hello World!

Failover Pluginを使わない場合

それではFailover Pluginを使わない場合の動作確認からしてみます。

せっかくなので、DBに接続する際の認証情報はAWS Secrets Manager Pluginを使って取得してみたいと思います。

pom.xmlを修正してsecretsmanagerとaws-advanced-jdbc-wrapperを依存関係に設定します。

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
        <modelVersion>4.0.0</modelVersion>
        <parent>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-starter-parent</artifactId>
                <version>3.1.0</version>
                <relativePath/> <!-- lookup parent from repository -->
        </parent>
        <groupId>net.non-97.aurora</groupId>
        <artifactId>jdbc</artifactId>
        <version>0.0.1-SNAPSHOT</version>
        <name>jdbc</name>
        <description>Demo project for Spring Boot</description>
        <properties>
                <java.version>17</java.version>
        </properties>
        <dependencies>
                <dependency>
                        <groupId>org.springframework.boot</groupId>
                        <artifactId>spring-boot-starter-web</artifactId>
                </dependency>

                <dependency>
                        <groupId>org.postgresql</groupId>
                        <artifactId>postgresql</artifactId>
                        <scope>runtime</scope>
                </dependency>
                <dependency>
                        <groupId>org.springframework.boot</groupId>
                        <artifactId>spring-boot-starter-test</artifactId>
                        <scope>test</scope>
                </dependency>

                <dependency>
                        <groupId>software.amazon.jdbc</groupId>
                        <artifactId>aws-advanced-jdbc-wrapper</artifactId>
                        <version>2.2.1</version>
                </dependency>
                <dependency>
                        <groupId>software.amazon.awssdk</groupId>
                        <artifactId>secretsmanager</artifactId>
                        <version>2.20.89</version>
                </dependency>

        </dependencies>

        <build>
                <plugins>
                        <plugin>
                                <groupId>org.springframework.boot</groupId>
                                <artifactId>spring-boot-maven-plugin</artifactId>
                        </plugin>
                </plugins>
        </build>

</project>

準備したJavaのアプリケーションは以下の通りです。

package jar;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;

import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;

public class JdbcApplication {
    // User configures connection properties here
    private static final String POSTGRESQL_CONNECTION_STRING = "jdbc:aws-wrapper:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB";

    public static void main(String[] args) {

        final Properties props = new Properties();

        props.setProperty("wrapperPlugins", "awsSecretsManager");
        props.setProperty("wrapperLoggerLevel", "FINE");
        props.setProperty("secretsManagerRegion", "us-east-1");
        props.setProperty("secretsManagerSecretId", "rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082");

        try {
            Connection conn = DriverManager.getConnection(POSTGRESQL_CONNECTION_STRING, props);
            while (true) {
                DateTimeFormatter dtformat = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");
                String date = dtformat.format(LocalDateTime.now()); 
                System.out.print(date + " : ");
                
                try {
                    Statement stmt = conn.createStatement();
                    ResultSet rs = stmt.executeQuery("SELECT inet_server_addr()");

                    if (rs.next()) {
                        System.out.println(rs.getString(1));
                    } else {
                        throw new SQLException("Failed to get IP address");
                    }
                } catch (SQLException e) {
                    System.err.println("Error: " + e.getMessage());
                    e.printStackTrace();
                }
                
                try {
                    Thread.sleep(800);
                } catch (Exception e) {
                    System.err.println("Error: " + e.getMessage());
                    e.printStackTrace();
                }
            }
        } catch (SQLException e) {
            System.err.println("Error: " + e.getMessage());
            e.printStackTrace();
        }
    }
}

Spring Bootを起動して、動作中にマネジメントコンソールからAurora DBクラスターをフェイルオーバーさせます。

$ mvn spring-boot:run
[INFO] Scanning for projects...
[INFO]
[INFO] -----------------------< net.non-97.aurora:jdbc >-----------------------
[INFO] Building jdbc 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] >>> spring-boot-maven-plugin:3.1.0:run (default-cli) > test-compile @ jdbc >>>
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:resources (default-resources) @ jdbc ---
[INFO] Copying 1 resource from src/main/resources to target/classes
[INFO] Copying 0 resource from src/main/resources to target/classes
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:compile (default-compile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :source
[INFO] Compiling 1 source file with javac [debug release 17] to target/classes
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:testResources (default-testResources) @ jdbc ---
[INFO] skip non existing resourceDirectory /home/ec2-user/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:testCompile (default-testCompile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :dependency
[INFO] Compiling 1 source file with javac [debug release 17] to target/test-classes
[INFO]
[INFO] <<< spring-boot-maven-plugin:3.1.0:run (default-cli) < test-compile @ jdbc <<<
[INFO]
[INFO]
[INFO] --- spring-boot-maven-plugin:3.1.0:run (default-cli) @ jdbc ---
[INFO] Attaching agents: []
2023/06/22 07:18:17.570 : 10.1.1.93
2023/06/22 07:18:18.437 : 10.1.1.93
2023/06/22 07:18:19.239 : 10.1.1.93
2023/06/22 07:18:20.041 : 10.1.1.93
2023/06/22 07:18:20.843 : 10.1.1.93
2023/06/22 07:18:21.660 : 10.1.1.93
2023/06/22 07:18:22.461 : 10.1.1.93
2023/06/22 07:18:23.265 : 10.1.1.93
2023/06/22 07:18:24.067 : 10.1.1.93
2023/06/22 07:18:24.869 : 10.1.1.93
2023/06/22 07:18:25.671 : 10.1.1.93
2023/06/22 07:18:26.473 : 10.1.1.93
2023/06/22 07:18:27.275 : 10.1.1.93
2023/06/22 07:18:28.077 : 10.1.1.93
2023/06/22 07:18:28.879 : 10.1.1.93
2023/06/22 07:18:29.682 : 10.1.1.93
2023/06/22 07:18:30.485 : 10.1.1.93
2023/06/22 07:18:31.286 : 10.1.1.93
2023/06/22 07:18:32.088 : 10.1.1.93
2023/06/22 07:18:32.890 : 10.1.1.93
2023/06/22 07:18:33.692 : Error: An I/O error occurred while sending to the backend.
org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:395)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:498)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:415)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:335)
        at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:321)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:297)
        at org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:246)
        at software.amazon.jdbc.wrapper.StatementWrapper.lambda$executeQuery$0(StatementWrapper.java:47)
        at software.amazon.jdbc.plugin.DefaultConnectionPlugin.execute(DefaultConnectionPlugin.java:101)
        at software.amazon.jdbc.ConnectionPluginManager.lambda$execute$3(ConnectionPluginManager.java:337)
        at software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$0(ConnectionPluginManager.java:276)
        at software.amazon.jdbc.ConnectionPluginManager.executeWithSubscribedPlugins(ConnectionPluginManager.java:258)
        at software.amazon.jdbc.ConnectionPluginManager.execute(ConnectionPluginManager.java:334)
        at software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:219)
        at software.amazon.jdbc.wrapper.StatementWrapper.executeQuery(StatementWrapper.java:41)
        at jar.JdbcApplication.main(JdbcApplication.java:37)
Caused by: java.io.EOFException
        at org.postgresql.core.PGStream.receiveChar(PGStream.java:467)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2155)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:368)
        ... 15 more
2023/06/22 07:18:34.505 : Error: This connection has been closed.
org.postgresql.util.PSQLException: This connection has been closed.
        at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:993)
        at org.postgresql.jdbc.PgConnection.createStatement(PgConnection.java:1819)
        at org.postgresql.jdbc.PgConnection.createStatement(PgConnection.java:518)
        at software.amazon.jdbc.wrapper.ConnectionWrapper.lambda$createStatement$9(ConnectionWrapper.java:281)
        at software.amazon.jdbc.plugin.DefaultConnectionPlugin.execute(DefaultConnectionPlugin.java:101)
        at software.amazon.jdbc.ConnectionPluginManager.lambda$execute$3(ConnectionPluginManager.java:337)
        at software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$0(ConnectionPluginManager.java:276)
        at software.amazon.jdbc.ConnectionPluginManager.executeWithSubscribedPlugins(ConnectionPluginManager.java:258)
        at software.amazon.jdbc.ConnectionPluginManager.execute(ConnectionPluginManager.java:334)
        at software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:219)
        at software.amazon.jdbc.wrapper.ConnectionWrapper.createStatement(ConnectionWrapper.java:275)
        at jar.JdbcApplication.main(JdbcApplication.java:36)
2023/06/22 07:18:35.306 : Error: This connection has been closed.
org.postgresql.util.PSQLException: This connection has been closed.
        at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:993)
        at org.postgresql.jdbc.PgConnection.createStatement(PgConnection.java:1819)
        at org.postgresql.jdbc.PgConnection.createStatement(PgConnection.java:518)
        at software.amazon.jdbc.wrapper.ConnectionWrapper.lambda$createStatement$9(ConnectionWrapper.java:281)
        at software.amazon.jdbc.plugin.DefaultConnectionPlugin.execute(DefaultConnectionPlugin.java:101)
        at software.amazon.jdbc.ConnectionPluginManager.lambda$execute$3(ConnectionPluginManager.java:337)
        at software.amazon.jdbc.ConnectionPluginManager.lambda$makePluginChainFunc$0(ConnectionPluginManager.java:276)
        at software.amazon.jdbc.ConnectionPluginManager.executeWithSubscribedPlugins(ConnectionPluginManager.java:258)
        at software.amazon.jdbc.ConnectionPluginManager.execute(ConnectionPluginManager.java:334)
        at software.amazon.jdbc.util.WrapperUtils.executeWithPlugins(WrapperUtils.java:219)
        at software.amazon.jdbc.wrapper.ConnectionWrapper.createStatement(ConnectionWrapper.java:275)
        at jar.JdbcApplication.main(JdbcApplication.java:36)
.
.
(以下略)
.
.

フェイルオーバーしたと思われるタイミングでDBに接続できなくなりました。

ステートメントの作成はループさせていますが、DBの接続はループさせていないので当然です。

Failover Pluginを使う場合 (DBインスタンス2台)

strict-writer

それではFailover Pluginを使ってみましょう。

Javaのアプリケーションは以下のようにしています。

package jar;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;
import software.amazon.jdbc.plugin.failover.FailoverFailedSQLException;
import software.amazon.jdbc.plugin.failover.FailoverSuccessSQLException;

import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;

public class JdbcApplication {
    // User configures connection properties here
    private static final String POSTGRESQL_CONNECTION_STRING = "jdbc:aws-wrapper:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB";

    public static void main(String[] args) {

        final Properties props = new Properties();

        props.setProperty("wrapperPlugins", "failover,awsSecretsManager");
        props.setProperty("wrapperLoggerLevel", "FINE");
        props.setProperty("secretsManagerRegion", "us-east-1");
        props.setProperty("secretsManagerSecretId", "rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082");

        try {
            Connection conn = DriverManager.getConnection(POSTGRESQL_CONNECTION_STRING, props);
            while (true) {
                DateTimeFormatter dtformat = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");
                String date = dtformat.format(LocalDateTime.now()); 
                System.out.print(date + " : ");
                
                try {
                    Statement stmt = conn.createStatement();
                    ResultSet rs = stmt.executeQuery("SELECT inet_server_addr()");

                    if (rs.next()) {
                        System.out.println(rs.getString(1));
                    } else {
                        throw new SQLException("Failed to get IP address");
                    }

                } catch (FailoverSuccessSQLException e) {
                    System.out.println("Failover succeeded, retrying query ...");
                } catch (FailoverFailedSQLException e) {
                    System.out.println("Failover failed ...");
                } catch (SQLException e) {
                    System.err.println("Error: " + e.getMessage());
                    e.printStackTrace();
                }
                
                try {
                    Thread.sleep(800);
                } catch (Exception e) {
                    System.err.println("Error: " + e.getMessage());
                    e.printStackTrace();
                }
            }
        } catch (SQLException e) {
            System.err.println("Error: " + e.getMessage());
            e.printStackTrace();
        }
    }
}

wrapperPluginsでfailoverをロードするようにしています。そして、フェイルオーバーが成功(FailoverSuccessSQLException)、失敗(FailoverFailedSQLException)した場合はメッセージを出力するようにしています。

例外が発生した際にConnectionオブジェクトを破棄しないようにしています。もし例外発生時にConnectionオブジェクトを破棄する場合、物理接続を切り替えたとしても切り替え後の接続後も破棄してしまうためです。

Warnings About Proper Usage of the AWS Advanced JDBC Driver

A common practice when using JDBC drivers is to wrap invocations against a Connection object in a try-catch block, and dispose of the Connection object if an Exception is hit. If this practice is left unaltered, the application will lose the fast-failover functionality offered by the JDBC Driver. When failover occurs, the JDBC Driver internally establishes a ready-to-use connection inside the original Connection object before throwing an exception to the user. If this Connection object is disposed of, the newly established connection will be thrown away. The correct practice is to check the SQL error code of the exception and reuse the Connection object if the error code indicates successful failover. The PostgreSQL Failover Sample Code demonstrates this practice. See the section about Failover Exception Codes for more details.

aws-advanced-jdbc-wrapper/docs/using-the-jdbc-driver/using-plugins/UsingTheFailoverPlugin.md at main · awslabs/aws-advanced-jdbc-wrapper · GitHub

それでは、実際に試してみましょう。

$ mvn spring-boot:run
[INFO] Scanning for projects...
[INFO]
[INFO] -----------------------< net.non-97.aurora:jdbc >-----------------------
[INFO] Building jdbc 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] >>> spring-boot-maven-plugin:3.1.0:run (default-cli) > test-compile @ jdbc >>>
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:resources (default-resources) @ jdbc ---
[INFO] Copying 1 resource from src/main/resources to target/classes
[INFO] Copying 0 resource from src/main/resources to target/classes
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:compile (default-compile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :source
[INFO] Compiling 1 source file with javac [debug release 17] to target/classes
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:testResources (default-testResources) @ jdbc ---
[INFO] skip non existing resourceDirectory /home/ec2-user/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:testCompile (default-testCompile) @ jdbc ---
[INFO] Changes detected - recompiling the module! :dependency
[INFO] Compiling 1 source file with javac [debug release 17] to target/test-classes
[INFO]
[INFO] <<< spring-boot-maven-plugin:3.1.0:run (default-cli) < test-compile @ jdbc <<<
[INFO]
[INFO]
[INFO] --- spring-boot-maven-plugin:3.1.0:run (default-cli) @ jdbc ---
[INFO] Attaching agents: []
Jun 22, 2023 7:19:58 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINE: Node is no longer available in the topology: HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-22 07:19:56.938784887]
2023/06/22 07:19:58.718 : 10.1.1.116
2023/06/22 07:19:59.531 : 10.1.1.116
.
.
(中略)
.
.
2023/06/22 07:20:38.860 : 10.1.1.116
2023/06/22 07:20:39.664 : 10.1.1.116
2023/06/22 07:20:40.466 : Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandlercall
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINE, user=postgresAdmin}'
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@714bf77e
Jun 22, 2023 7:20:40 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:20:51 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:20:51 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE,weight=5, null]
Jun 22, 2023 7:20:51 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/22 07:20:52.076 : 10.1.1.93
2023/06/22 07:20:52.899 : 10.1.1.93
2023/06/22 07:20:53.703 : 10.1.1.93
2023/06/22 07:20:54.505 : 10.1.1.93
2023/06/22 07:20:55.307 : 10.1.1.93

12秒ほどで再接続していますね。DBへの接続はループさせていないため、論理接続は維持しながら物理接続が切り替わっていることが分かります。

続いて、もう少しFailover Pluginの動きを見たいのでログレベルをFINESTに変更して、再度検証します。

$ mvn spring-boot:run
[INFO] Scanning for projects...
[INFO]
[INFO] -----------------------< net.non-97.aurora:jdbc >-----------------------
[INFO] Building jdbc 0.0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] >>> spring-boot-maven-plugin:3.1.0:run (default-cli) > test-compile @ jdbc >>>
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:resources (default-resources) @ jdbc ---
[INFO] Copying 1 resource from src/main/resources to target/classesb-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com
[INFO] Copying 0 resource from src/main/resources to target/classes
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:compile (default-compile) @ jdbc ---
[INFO] Nothing to compile - all classes are up to date
[INFO]
[INFO] --- maven-resources-plugin:3.3.1:testResources (default-testResources) @ jdbc ---
[INFO] skip non existing resourceDirectory /home/ec2-user/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.11.0:testCompile (default-testCompile) @ jdbc ---
[INFO] Nothing to compile - all classes are up to date
[INFO]
[INFO] <<< spring-boot-maven-plugin:3.1.0:run (default-cli) < test-compile @ jdbc <<<
[INFO]
[INFO]
[INFO] --- spring-boot-maven-plugin:3.1.0:run (default-cli) @ jdbc ---
[INFO] Attaching agents: []
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.targetdriverdialect.TargetDriverDialectManager logDialect
FINEST: Target driver dialect set to: 'pgjdbc', software.amazon.jdbc.targetdriverdialect.PgTargetDriverDialect@136432db.
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin initHostProvider
FINER: failoverMode=STRICT_WRITER
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100,2023-06-22 07:24:21.390787883]
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 22, 2023 7:24:21 AM software.amazon.jdbc.PluginServiceImpl getCurrentHostSpec
FINEST: Set current host to HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-22 07:24:21.390787883]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Cluster endpoint resolves to 10.1.1.116.
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
        Host 'db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINE: Node is no longer available in the topology: HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-22 07:24:21.390787883]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Writer host: HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Writer host address: 10.1.1.116
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
2023/06/22 07:24:22.613 : Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:24:22 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
2023/06/22 07:24:23.424 : Jun 22, 2023 7:24:23 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:24:23 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=720, 2023-06-22 07:24:21.0]
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:24:23 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:24:23 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:24:23 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
.
.
(中略)
.
.
2023/06/22 07:25:14.893 : Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2030, 2023-06-22 07:24:51.0]
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=18, null]
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandlercall
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:14 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@7f4feaaf
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:16 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:17 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=33, null]
Jun 22, 2023 7:25:17 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:18 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:19 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=4, null]
Jun 22, 2023 7:25:19 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:20 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:21 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=5, null]
Jun 22, 2023 7:25:21 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:22 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:23 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=28, null]
Jun 22, 2023 7:25:23 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2256, 2023-06-22 07:25:24.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, null]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE, weight=2256,2023-06-22 07:25:24.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, null]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINEST: Current reader connection is actually a new writer connection.
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE,weight=16, null]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE, weight=2256,2023-06-22 07:25:24.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, null]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_UP, NODE_CHANGED]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.PluginServiceImpl setAvailability
FINEST: There are no changes in the hosts availability.
Jun 22, 2023 7:25:25 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandlercall
FINER: [TaskA] Finished
2023/06/22 07:25:26.209 : Jun 22, 2023 7:25:26 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:26 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:26 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:26 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:26 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:27.021 : Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:27.824 : Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:27 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:28.626 : Jun 22, 2023 7:25:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:28 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=16, 2023-06-22 07:25:25.0]
Jun 22, 2023 7:25:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
.
.
(中略)
.
.
2023/06/22 07:25:55.915 : Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:55 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:56.719 : Jun 22, 2023 7:25:56 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:56 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:56 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:56 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:56 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:57.521 : Jun 22, 2023 7:25:57 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:57 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:57 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:57 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:57 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:58.323 : Jun 22, 2023 7:25:58 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:58 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:58 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:58 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:58 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/22 07:25:59.125 : Jun 22, 2023 7:25:59 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 22, 2023 7:25:59 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1016, 2023-06-22 07:25:54.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=22, null]
Jun 22, 2023 7:25:59 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 22, 2023 7:25:59 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 22, 2023 7:25:59 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93

12秒でフェイルオーバーしました。

ログの内容からフェイルオーバー時に以下の処理を行っていることが分かります。

ノードの状態が変化したことを検知
内部トポロジの状態を更新
Writerへの再接続(Task A)
新しいWriterへの接続(Task B)
1. 内部トポロジからAuroraレプリカへの接続
2. 内部トポロジの状態を更新
接続完了後、現在接続しているAuroraレプリカが新しいWriterであることを確定
新しいWriterの接続が完了したタイミングで、フェイルオーバー成功と判定

その後、5回ほど再度フェイルオーバー時のダウンタイムを計測しましたが、いずれも10-13秒でした。

高速というほど高速ではありませんが、DNSを使ってフェイルオーバーした際に発生するIPアドレスのフラつきは発生せずに安定しています。

reader-or-writer

Failover Pluginのプロパティを眺めているとfailoverModeに以下説明がありました。

Defines a mode for failover process. Failover process may prioritize nodes with different roles and connect to them. Possible values:

strict-writer - Failover process follows writer node and connects to a new writer when it changes.

reader-or-writer - During failover, the driver tries to connect to any available/accessible reader node. If no reader is available, the driver will connect to a writer node. This logic mimics the logic of the Aurora read-only cluster endpoint.

strict-reader - During failover, the driver tries to connect to any available reader node. If no reader is available, the driver raises an error. Reader failover to a writer node will only be allowed for single-node clusters. This logic mimics the logic of the Aurora read-only cluster endpoint.

If this parameter is omitted, default value depends on connection url. For Aurora read-only cluster endpoint, it's set to reader-or-writer. Otherwise, it's strict-writer.

aws-advanced-jdbc-wrapper/docs/using-the-jdbc-driver/using-plugins/UsingTheFailoverPlugin.md at main · awslabs/aws-advanced-jdbc-wrapper · GitHub

今まではクラスターエンドポイントに対して接続していたので、新しいWriterに接続しようとするstrict-writerで実行されていたようです。

試しにReaderにアクセスできない場合はWriterにアクセスするreader-or-writerの動作を確認してみます。

Javaのアプリケーションは以下の通りです。

package jar;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;
import software.amazon.jdbc.plugin.failover.FailoverFailedSQLException;
import software.amazon.jdbc.plugin.failover.FailoverSuccessSQLException;

import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;

public class JdbcApplication {
    // User configures connection properties here
    private static final String POSTGRESQL_CONNECTION_STRING = "jdbc:aws-wrapper:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB";

    public static void main(String[] args) {

        final Properties props = new Properties();

        props.setProperty("wrapperPlugins", "failover,awsSecretsManager");
        props.setProperty("wrapperLoggerLevel", "FINEST");
        props.setProperty("failoverMode", "reader-or-writer");
        props.setProperty("secretsManagerRegion", "us-east-1");
        props.setProperty("secretsManagerSecretId", "rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082");

        try {
            Connection conn = DriverManager.getConnection(POSTGRESQL_CONNECTION_STRING, props);
            while (true) {
                DateTimeFormatter dtformat = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");
                String date = dtformat.format(LocalDateTime.now()); 
                System.out.print(date + " : ");
                
                try {
                    Statement stmt = conn.createStatement();
                    ResultSet rs = stmt.executeQuery("SELECT inet_server_addr()");

                    if (rs.next()) {
                        System.out.println(rs.getString(1));
                    } else {
                        throw new SQLException("Failed to get IP address");
                    }

                } catch (FailoverSuccessSQLException e) {
                    System.out.println("Failover succeeded, retrying query ...");
                } catch (FailoverFailedSQLException e) {
                    System.out.println("Failover failed ...");
                } catch (SQLException e) {
                    System.err.println("Error: " + e.getMessage());
                    e.printStackTrace();
                }
                
                try {
                    Thread.sleep(800);
                } catch (Exception e) {
                    System.err.println("Error: " + e.getMessage());
                    e.printStackTrace();
                }
            }
        } catch (SQLException e) {
            System.err.println("Error: " + e.getMessage());
            e.printStackTrace();
        }
    }
}

この状態でJavaアプリケーション実行中にAurora DBクラスターのフェイルオーバーを実行します。

$ mvn spring-boot:run
.
.
(中略)
.
.
[INFO] Attaching agents: []
Jun 23, 2023 8:25:48 AM software.amazon.jdbc.targetdriverdialect.TargetDriverDialectManager logDialect
FINEST: Target driver dialect set to: 'pgjdbc', software.amazon.jdbc.targetdriverdialect.PgTargetDriverDialect@136432db.
Jun 23, 2023 8:25:48 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin initHostProvider
FINER: failoverMode=READER_OR_WRITER
Jun 23, 2023 8:25:49 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-23 08:25:48.994994758]
Jun 23, 2023 8:25:49 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 23, 2023 8:25:49 AM software.amazon.jdbc.PluginServiceImpl getCurrentHostSpec
FINEST: Set current host to HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-23 08:25:48.994994758]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Cluster endpoint resolves to 10.1.1.93.
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=6, null]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
        Host 'db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINE: Node is no longer available in the topology: HostSpec[host=db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=100, 2023-06-23 08:25:48.994994758]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=6, null]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Writer host: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE,weight=6, null]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.staledns.AuroraStaleDnsHelper getVerifiedConnection
FINEST: Writer host address: 10.1.1.93
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=6, null]
2023/06/23 08:25:50.206 : Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=6, null]
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:25:50 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
.
.
(中略)
.
.
2023/06/23 08:26:28.806 : Jun 23, 2023 8:26:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:28 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1853, 2023-06-23 08:26:20.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=18, null]
Jun 23, 2023 8:26:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:26:28 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/23 08:26:29.609 : Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1853, 2023-06-23 08:26:20.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=18, null]
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Starting reader failover procedure.
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.PluginServiceImpl setAvailability
FINEST: There are no changes in the hosts availability.
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=reader-or-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=reader-or-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 23, 2023 8:26:29 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Failed to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@48da0960
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Connected to: HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2609, 2023-06-23 08:25:50.0]
Jun 23, 2023 8:26:30 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/23 08:26:31.235 : Jun 23, 2023 8:26:31 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:31 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 23, 2023 8:26:31 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:31 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:26:31 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
2023/06/23 08:26:32.043 : Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116
2023/06/23 08:26:32.846 : Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 23, 2023 8:26:32 AM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.116

2秒ほどでフェイルオーバーしました。これは速いですね。

100msec間隔でループするように修正して、再実行してみます。

package jar;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.util.Properties;
import software.amazon.jdbc.plugin.failover.FailoverFailedSQLException;
import software.amazon.jdbc.plugin.failover.FailoverSuccessSQLException;

import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;

public class JdbcApplication {
    // User configures connection properties here
    private static final String POSTGRESQL_CONNECTION_STRING = "jdbc:aws-wrapper:postgresql://db-cluster.cluster-cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB";

    public static void main(String[] args) {

        final Properties props = new Properties();

        props.setProperty("wrapperPlugins", "failover,awsSecretsManager");
        props.setProperty("wrapperLoggerLevel", "FINER");
        props.setProperty("failoverMode", "reader-or-writer");
        props.setProperty("secretsManagerRegion", "us-east-1");
        props.setProperty("secretsManagerSecretId", "rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082");

        try {
            Connection conn = DriverManager.getConnection(POSTGRESQL_CONNECTION_STRING, props);
            while (true) {
                DateTimeFormatter dtformat = DateTimeFormatter.ofPattern("yyyy/MM/dd HH:mm:ss.SSS");
                String date = dtformat.format(LocalDateTime.now()); 
                System.out.print(date + " : ");
                
                try {
                    Statement stmt = conn.createStatement();
                    ResultSet rs = stmt.executeQuery("SELECT inet_server_addr()");

                    if (rs.next()) {
                        System.out.println(rs.getString(1));
                    } else {
                        throw new SQLException("Failed to get IP address");
                    }

                } catch (FailoverSuccessSQLException e) {
                    System.out.println("Failover succeeded, retrying query ...");
                } catch (FailoverFailedSQLException e) {
                    System.out.println("Failover failed ...");
                } catch (SQLException e) {
                    System.err.println("Error: " + e.getMessage());
                    e.printStackTrace();
                }
                
                try {
                    Thread.sleep(100);
                } catch (Exception e) {
                    System.err.println("Error: " + e.getMessage());
                    e.printStackTrace();
                }
            }
        } catch (SQLException e) {
            System.err.println("Error: " + e.getMessage());
            e.printStackTrace();
        }
    }
}

実行結果は以下の通りです。

2023/06/23 08:41:35.732 : 10.1.1.116
2023/06/23 08:41:35.833 : 10.1.1.116
2023/06/23 08:41:35.935 : 10.1.1.116
2023/06/23 08:41:36.037 : 10.1.1.116
2023/06/23 08:41:36.140 : Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Starting reader failover procedure.
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=reader-or-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=reader-or-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Failed to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@1533f902
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverReader
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1551, 2023-06-23 08:41:08.0]
Jun 23, 2023 8:41:36 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/23 08:41:36.571 : 10.1.1.93
2023/06/23 08:41:36.677 : 10.1.1.93
2023/06/23 08:41:36.779 : 10.1.1.93
2023/06/23 08:41:36.880 : 10.1.1.93
2023/06/23 08:41:36.981 : 10.1.1.93

0.4秒でフェイルオーバーしていますね。この後5回やっていずれも0.4秒でした。これはなかなか速いですね。

Failover Pluginを使う場合 (DBインスタンス3台)

先の検証からstrict-writerを使用する場合、新しいWriterへの接続(Task B)の中で旧Writerへの接続がループしていることが気になりました。

具体的には以下です。

Jun 22, 2023 7:25:15 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 22, 2023 7:25:15 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:16 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:17 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=33, null]
Jun 22, 2023 7:25:17 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:18 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:19 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=4, null]
Jun 22, 2023 7:25:19 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 22, 2023 7:25:20 AM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 22, 2023 7:25:21 AM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=5, null]
Jun 22, 2023 7:25:21 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.

旧Auroraレプリカでフェイルオーバー先であろうdb-instance-aに接続して、db-instance-aの状態がWRITERであることが判明していることに関わらず、旧Writerdb-instance-bに接続できるまで待っているのに疑問を持ちました。

もしかすると、複数台のDBインスタンスに接続して状態がWRITERであるという確信を持てなければフェイルオーバーしない作りなのでしょうか。

[TaskB] Host {0} is not yet connected to a cluster. The cluster is still being reconfigured.というメッセージを出力する箇所を調査すると ClusterAwareWriterFailoverHandler.javaのrefreshTopologyAndConnectToNewWriter()でトポロジサイズが1である場合は、「現在接続されているリーダーはフェイルオーバー中で、スタンドアロンノードとして動作している」として、何もしないようです。

    /**
     * Re-read topology and wait for a new writer.
     *
     * @return Returns true if successful.
     */
    private boolean refreshTopologyAndConnectToNewWriter() throws InterruptedException {
      while (true) {
        try {
          pluginService.forceRefreshHostList(this.currentReaderConnection);
          final List<HostSpec> topology = pluginService.getHosts();

          if (!topology.isEmpty()) {

            if (topology.size() == 1) {
              // The currently connected reader is in a middle of failover. It's not yet connected
              // to a new writer adn works in as "standalone" node. The handler needs to
              // wait till the reader gets connected to entire cluster and fetch a proper
              // cluster topology.

              // do nothing
              LOGGER.finest(() -> Messages.get("ClusterAwareWriterFailoverHandler.standaloneNode",
                  new Object[]{this.currentReaderHost.getUrl()}));

            } else {
              this.currentTopology = topology;
              final HostSpec writerCandidate = getWriter(this.currentTopology);

              if (!isSame(writerCandidate, this.originalWriterHost)) {
                // new writer is available, and it's different from the previous writer
                LOGGER.finest(() -> Utils.logTopology(this.currentTopology, "[TaskB] "));
                if (connectToWriter(writerCandidate)) {
                  return true;
                }
              }
            }
          }
        } catch (final SQLException e) {
          LOGGER.finer(
              () -> Messages.get(
                  "ClusterAwareWriterFailoverHandler.taskBEncounteredException",
                  new Object[] {e}));
          return false;
        }

        TimeUnit.MILLISECONDS.sleep(readTopologyIntervalMs);
      }
    }

つまりはDBインスタンスが3台以上いれば、strict-writerであっても10秒未満でフェイルオーバーできるということでしょうか。

DBインスタンスを追加して検証してみます。追加したDBインスタンスのIPアドレスは以下の通りです。

$ dig db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com +short
10.1.1.77

DBインスタンス追加後の実行結果は以下の通りです。

2023/06/23 08:54:55.987 : 10.1.1.93
2023/06/23 08:54:56.789 : 10.1.1.93
2023/06/23 08:54:57.591 : 10.1.1.93
2023/06/23 08:54:58.393 : 10.1.1.93
2023/06/23 08:54:59.195 : Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@2ee47fbb
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:54:59 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@1ad2cc68
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=19, null]
Jun 23, 2023 8:55:01 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/23 08:55:02.413 : 10.1.1.77
2023/06/23 08:55:03.221 : 10.1.1.77
2023/06/23 08:55:04.023 : 10.1.1.77
2023/06/23 08:55:04.825 : 10.1.1.77

strict-writerであっても3秒でフェイルオーバーしましたね。

100msec間隔でDBに接続するように修正して、再度検証してみます。

2023/06/23 08:57:46.484 : 10.1.1.77
2023/06/23 08:57:46.585 : 10.1.1.77
2023/06/23 08:57:46.687 : 10.1.1.77
2023/06/23 08:57:46.788 : Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=strict-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=strict-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@22224a7d
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:46 AM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@7daf864d
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINE: [TaskB] Trying to connect to a new writer: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-23 08:57:56.0]
Jun 23, 2023 8:57:57 AM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/23 08:57:57.274 : 10.1.1.93
2023/06/23 08:57:57.393 : 10.1.1.93
2023/06/23 08:57:57.495 : 10.1.1.93

次は11秒もかかってしまいました。

ログレベルをFINESTに変更して再度確認します。

2023/06/25 21:28:32.106 : Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=805, 2023-06-25 21:28:09.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=803, 2023-06-25 21:28:09.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=33, null]
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.77
2023/06/25 21:28:32.908 : Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=805, 2023-06-25 21:28:09.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=803, 2023-06-25 21:28:09.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=33, null]
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:28:32 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@6c6a12eb
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@631f4046
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=24, null]
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
        Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 25, 2023 9:28:33 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:28:34 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINEST: Current reader connection is actually a new writer connection.
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:35 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/25 21:28:36.125 : Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/25 21:28:36.939 : Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=37811, 2023-06-25 21:28:34.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=26, null]
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:28:36 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93

次は4秒でフェイルオーバーが完了しました。

もう一度やってみましょう。

2023/06/25 21:36:44.599 : Jun 25, 2023 9:36:44 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:36:44 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2401, 2023-06-25 21:36:24.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=702, 2023-06-25 21:36:24.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=7, null]
Jun 25, 2023 9:36:44 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:36:44 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:36:44 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/25 21:36:45.402 : Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=2401, 2023-06-25 21:36:24.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=702, 2023-06-25 21:36:24.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=7, null]
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@20ee6e78
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=27, 2023-06-25 21:36:45.0]
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
        Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
        Host 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:45 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@631f4046
Jun 25, 2023 9:36:47 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:47 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=21, 2023-06-25 21:36:47.0]
Jun 25, 2023 9:36:47 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:49 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:49 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=11, 2023-06-25 21:36:49.0]
Jun 25, 2023 9:36:49 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:51 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:51 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=7, 2023-06-25 21:36:51.0]
Jun 25, 2023 9:36:51 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:53 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:53 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=7, 2023-06-25 21:36:53.0]
Jun 25, 2023 9:36:53 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Host db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/ is not yet connected to a cluster. The cluster is still being reconfigured.
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=74, 2023-06-25 21:36:53.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_ADDED]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE,weight=74, 2023-06-25 21:36:53.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINE: [TaskB] Trying to connect to a new writer: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE,weight=74, 2023-06-25 21:36:53.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:55 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/25 21:36:56.527 : Jun 25, 2023 9:36:56 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:36:56 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE,weight=74, 2023-06-25 21:36:53.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:56 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:36:56 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:36:56 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.77
2023/06/25 21:36:57.349 : Jun 25, 2023 9:36:57 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 9:36:57 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, NOT_AVAILABLE,weight=74, 2023-06-25 21:36:53.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=34, 2023-06-25 21:36:55.0]
Jun 25, 2023 9:36:57 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 9:36:57 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 9:36:57 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.77

今度はフェイルオーバー完了までに11秒かかりました。

もしかすると、Auroraレプリカの再起動のタイミングによっては3台であっても同時に複数台のDBインスタンスに接続できていないのでしょうか。

Failover Pluginを使う場合 (DBインスタンス4台)

DBインスタンスを4台に増やすとどうでしょうか。

2023/06/25 22:27:30.766 : Jun 25, 2023 10:27:30 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 10:27:30 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1204, 2023-06-25 22:26:59.0]
   HostSpec[host=db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1202, 2023-06-25 22:26:59.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1208, 2023-06-25 22:26:59.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=4, null]
Jun 25, 2023 10:27:30 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 10:27:30 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 10:27:30 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.77
2023/06/25 22:27:31.569 : Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1204, 2023-06-25 22:26:59.0]
   HostSpec[host=db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1202, 2023-06-25 22:26:59.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=1208, 2023-06-25 22:26:59.0]
   HostSpec[host=db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=4, null]
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [WENT_DOWN, NODE_CHANGED]
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager,wrapperLoggerLevel=FINEST, user=postgresAdmin}'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.DriverConnectionProvider connect
FINEST: Connecting to jdbc:postgresql://db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/testDB
with properties:
[secretsManagerSecretId] rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082
[password] 2nJW1|t[Il#dpHbiloAg20IDP|gq
[secretsManagerRegion] us-east-1
[user] postgresAdmin
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@22224a7d
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.dialect.DialectManager logCurrentDialect
FINEST: Current dialect: aurora-pg, software.amazon.jdbc.dialect.AuroraPgDialect, canUpdate: false
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:31 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@59ad88e5
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider forceRefresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin notifyNodeListChanged
FINEST: Changes:
        Host 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [PROMOTED_TO_WRITER, NODE_CHANGED]
        Host 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
        Host 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/': [NODE_DELETED]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler refreshTopologyAndConnectToNewWriter
FINEST: [TaskB] Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINEST: Current reader connection is actually a new writer connection.
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/25 22:27:32.859 : Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 10:27:32 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93
2023/06/25 22:27:33.667 : Jun 25, 2023 10:27:33 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Connection.createStatement'
Jun 25, 2023 10:27:33 PM software.amazon.jdbc.hostlistprovider.AuroraHostListProvider refresh
FINEST: Topology:
   HostSpec[host=db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, READER, AVAILABLE, weight=8, 2023-06-25 22:27:30.0]
   HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=0, null]
Jun 25, 2023 10:27:33 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'Statement.executeQuery'
Jun 25, 2023 10:27:33 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.next'
Jun 25, 2023 10:27:33 PM software.amazon.jdbc.plugin.DefaultConnectionPlugin execute
FINEST: Executing method: 'ResultSet.getString'
10.1.1.93

2秒でフェイルオーバーが完了しましたね。

もう一度やってみます。

2023/06/25 22:33:42.050 : 10.1.1.77
2023/06/25 22:33:42.151 : 10.1.1.77
2023/06/25 22:33:42.252 : 10.1.1.77
2023/06/25 22:33:42.354 : Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin dealWithOriginalException
FINER: Detected an exception while executing a command: An I/O error occurred while sending to the backend.
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Starting writer failover procedure.
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Attempting to connect to a new writer instance.
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINE: [TaskA] Attempting to re-connect to the current writer instance: 'db-instance-c.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=strict-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Trying to connect to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/', with properties '{failoverMode=strict-writer, secretsManagerSecretId=rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082, database=testDB, password=2nJW1|t[Il#dpHbiloAg20IDP|gq, secretsManagerRegion=us-east-1, wrapperPlugins=failover,awsSecretsManager, wrapperLoggerLevel=FINER, user=postgresAdmin}'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@6720c8fd
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToReader
FINE: [TaskB] Connected to reader: 'db-instance-b.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: Connected to reader: 'db-instance-d.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:42 PM software.amazon.jdbc.plugin.failover.ClusterAwareReaderFailoverHandler$ConnectionAttemptTask call
FINE: New reader connection object: org.postgresql.jdbc.PgConnection@55763653
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler connectToWriter
FINE: [TaskB] Trying to connect to a new writer: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$WaitForNewWriterHandler call
FINER: [TaskB] Finished
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler$ReconnectToWriterHandler call
FINER: [TaskA] Finished
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.ClusterAwareWriterFailoverHandler logTaskSuccess
FINE: Successfully connected to the new writer instance: 'db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com:5432/'
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failoverWriter
FINE: Connected to: HostSpec[host=db-instance-a.cicjym7lykmq.us-east-1.rds.amazonaws.com, port=5432, WRITER, AVAILABLE, weight=9, 2023-06-25 22:33:46.0]
Jun 25, 2023 10:33:46 PM software.amazon.jdbc.plugin.failover.FailoverConnectionPlugin failover
SEVERE: The active SQL connection has changed due to a connection failure. Please re-configure session state if required.
Failover succeeded, retrying query ...
2023/06/25 22:33:46.763 : 10.1.1.93
2023/06/25 22:33:46.881 : 10.1.1.93
2023/06/25 22:33:46.983 : 10.1.1.93

次は4秒でフェイルオーバーが完了しました。

この後10回ほどリトライしましたが、いずれも2-5秒でした。

フェイルオーバー時のダウンタイムの許容時間がこのぐらいであれば、DBインスタンスが4台以上必要そうです。

RDS Proxy

おまけでRDS Proxy経由でアクセスした場合のダウンタイムを計測してみます。

RDS Proxyを追加して0.1秒間隔でRDS Proxyにアクセスした場合、通信できないタイミングがあるか確認します。

# シークレットから認証情報を取得
$ get_secrets_value=$(aws secretsmanager get-secret-value \
    --secret-id 'rds!cluster-f23ebbb3-8697-4046-aed9-f897ad4a2082' \
    --region us-east-1 \
    | jq -r .SecretString)

# 環境変数に埋め込み
$ export PGHOST='db-proxy.proxy-cicjym7lykmq.us-east-1.rds.amazonaws.com'
$ export PGDATABASE=testDB
$ export PGUSER=$(echo "${get_secrets_value}" | jq -r .username)
$ export PGPASSWORD=$(echo "${get_secrets_value}" | jq -r .password)

# 0.1秒間隔でRDS Proxyにアクセス
$ while true; do
  date +"%H:%M:%S.%3N " | tr -d "\n"
  echo "SELECT inet_server_addr();" | psql -t
  sleep 0.1
done
.
.
(中略)
.
.
08:16:14.997  10.1.1.93

08:16:15.151  10.1.1.93

08:16:15.303  10.1.1.93

08:16:15.462  10.1.1.77

08:16:16.003  10.1.1.77

08:16:16.175  10.1.1.77

0.15秒未満でフェイルオーバーしていますね。DBインスタンスを4台構成から2台構成にしても同じく0.15秒未満でフェイルオーバーしていました。

RDS Proxyの制約事項やコスト、レイテンシーが許容できるのであれば、RDS Proxyを使う方が幸せかもしれません。